Delay in DTMF Detection

[lucasklos]

Hello, 

We are having an issue where  DTMF # is recognized several seconds before it is pressed.

Below is an extract of the ktTel.txt log.

771 165601.118  1380   2 ev    TDX_CST (CST Event Received)
772 165601.118  1380   2       TDX_CST DE_DIGITS data=55 [7], KeysUsed=0
773 165601.118  1380   2       TDX_CST DE_TONEON. On SIP systems dtmf events raised by tel_ev only as <dtmf>inband</dtmf> not specified in Config.xml <Channel><Options> section.
774 165601.168  2468           1|20 wrote 756 (lines=9) or=0 max=34697/320 curr=0
775 165602.740  1380   3       ev idx=52 : evttype=2206(2206), crn=8000001, data=0147F458(0A2D14E8), len=8(8) q: 0/7
776 165602.740  1380   3 ev    TEL_EV
777 165602.740  1380   3       TEL_EV received: id 7 vol 4 dur 640
778 165602.740  1380   3       Event_Dtmf iParam1=0x37 iParam2=0x4
779 165602.740  1380   3 r     dtmf 7
780 165602.827  1380   2       ev idx=53 : evttype=134(134), crn=0, data=04FA3D28(0A2D14E8), len=4(4) q: 0/7
781 165602.827  1380   2 ev    TDX_CST (CST Event Received)
782 165602.827  1380   2       TDX_CST DE_DIGITS data=35 [#], KeysUsed=0
783 165602.827  1380   2       TDX_CST DE_TONEON. On SIP systems dtmf events raised by tel_ev only as <dtmf>inband</dtmf> not specified in Config.xml <Channel><Options> section.
784 165602.920  2468           0|21 wrote 756 (lines=9) or=0 max=34697/320 curr=1
785 165608.636  3660   3 fn    PlayStart(iLineId=3, sFileList=,D:\ITsynch\AIMS\AIMS.IVR\SoundFiles\202_AssetCode.wav, sXMLOptions=)
786 165608.636  3660           ExtractFromOptionsXml_Keys iKeysDefLen=0
787 165608.636  3660           ExtractFromOptionsXml_Keys : 
788 165608.636  3660   3       PlayStart(hLine=3, strSoundFile=,D:\ITsynch\AIMS\AIMS.IVR\SoundFiles\202_AssetCode.wav, iPlayId=683906(0xa6f82), iParam1=0, iParam2=0, zsParam1=, zsParam2=, keys-notused)
789 165608.636  3660   3       play  start (hli=0ABB77F8, strSoundFile=,D:\ITsynch\AIMS\AIMS.IVR\SoundFiles\202_AssetCode.wav, iPlayId=683906(0xa6f82), iParam1=0, iParam2=0, zsParam1=, zsParam2=)
790 165608.636  3660   3       play  readin loop: idx=0/500, fnamelen=53
791 165608.636  3660           wav: format=7, channels=1, hz=8000, bytes/sec=8000, bytes/sample=1, bits/sample=8, DataBlockSize=18960  D:\ITsynch\AIMS\AIMS.IVR\SoundFiles\202_AssetCode.wav
792 165608.636  3660   3       iXpbSampleRateDRT_FirstFile = DRT_8KHZ
793 165608.636  3660   3       iXpbBitsPerSample_FirstFile = 8 (as per returned data)
794 165608.636  3660   3       XpbDataFormat: DATA_FORMAT_MULAW, rate_const=0x40, bits=8 (iWavFilesEncodingFormat_LastFile=7)
795 165608.636  3660   3       buffer merge add loop hPlayIott_Curr=0x11588c38, ptrVoiceData=0x115ce740, io_bufp=0x115c9d18, io_length=18958
796 165608.636  3660   3       buffer merge end. calc=18958, copied=18958. hPlayIott_Start=0x11588dc8
797 165608.636  3660   3       dx_setevtmsk => 0
798 165608.636  3660   2       dx_clrsvcond => 0
799 165608.636  3660   2       dx_setsvmt SV_SPEEDTBL ok
800 165608.636  3660   2       dx_getsvmt ok
801 165608.636  3660           SV_SPEEDTBL decrease [ -128 -128 -128 -128 -128 -50 -40 -30 -20 -10 ] 
802 165608.636  3660           SV_SPEEDTBL origin 0
803 165608.636  3660           SV_SPEEDTBL increase [ 10 20 30 40 50 -128 -128 -128 -128 -128 ] 
804 165608.636  3660   2       dx_getcursv 2 Volume = 0 Speed = 0

805 165608.636  3660   3       KeyControlsUsed false
806 165608.636  3660   3       dx_adjsv dev=2, speed, reset => 0 (no speed keys set on play)
807 165608.636  3660   3       play xpb: wDataFormat=7, wFileFormat=1, nSamplesPerSec=0x40, wBitsPerSample=8 ()
808 165608.636  3660   3       play(2, iott=0x11588dc8 (len=18958, buff=0x115ce740), tpt=0x0, xpb=0xabb88c8) call
809 165608.636  3660   3       play(2, 0x11588dc8, tpt=0x0, xpb=0xabb88c8) => 0, hli=0ABB77F8
810 165608.678  2468           1|22 wrote 2459 (lines=25) or=0 max=34697/320 curr=0
811 165611.152  1380   2       ev idx=54 : evttype=129(129), crn=0, data=04FA3FF8(0A2D14E8), len=0(0) q: 0/7
812 165611.152  1380   2 ev    TDX_PLAY (Play Completed)
813 165611.152  1380   3       EvHandler_TDX_PLAY  hPlayRec_IottChainStart=0x11588dc8
814 165611.152  1380   3       play  free(0x115ce740, 0x11588dc8) eot
815 165611.152  1380   3       Event_PlayEnd raise: hli=0ABB77F8, dwPlayIdJustFinished=683906 [0:0:18958] 
816 165611.152  1380   3       Event_PlayEnd begin
817 165611.152  1380   3 r     PlayEnd 683906
818 165611.183  2468           0|23 wrote 533 (lines=7) or=0 max=34697/320 curr=1
819 165613.237  1380   3       ev idx=55 : evttype=2206(2206), crn=8000001, data=04FA3F98(0A2D14E8), len=8(8) q: 0/7
820 165613.237  1380   3 ev    TEL_EV
821 165613.237  1380   3       TEL_EV received: id 11 vol 4 dur 640
822 165613.237  1380   3       Event_Dtmf iParam1=0x23 iParam2=0x4
823 165613.237  1380   3 r     dtmf #

As you can see, the event # is received at 165602.827, but recognized at 165613.237 (almost 11 secs after if was received).

This is not happening with all the digits pressed by the user, for instance, the previous digit was 7, event received at: 165601.118 and recognized as DTMF 7 at 165602.740 (almost 400ms after).

This is causing timeouts in our scripts.
I'm attaching the logs, any guidance is really appreciated.

Regards

 

vg_logs.zip

[SupportTeam]

Looks like telephone keypad key-presses on this system are sent as 'inband' audible DTMF tones, and not as RFC 2833 events.

Was this a recent change?

Would strongly recommend changing the keypress/DTMF settings on whatever is placing the calls into the VoiceGuide system to use RFC 2833 for the keypress signalling. Pretty much all VoIP systems out there are able to use RFC 2833 instead of sending keypresses as audible ('in-band') DTMF tones.

 

If you are unable to use RFC 2833 then please try setting  

<dtmf>inband</dtmf>

in VoiceGuide's Config.xml <Channel><Options> section, and then restart the VoiceGuide service.

This sets VoiceGuide to react to the heard DTMF tones instead of RFC 2833 events.

If you have to stick with using audible DTMF tones then setting <dtmf>inband</dtmf> in Config.xml <Channel><Options> section should also result in system immediately reacting to the heard tones - as we can see in traces that the DTMF tones were detected by HMP.

 

We would need to see a WireShark trace that captured RTP and event data to better see what is actually happening on this call, but the fact that an old version of HMP is used on this system may be a factor here.

The version of Dialogic HMP used on this system is over 12 years old - HMP SU 354 (and the version of VoiceGuide is from 2014 - matched to that HMP SU 354). So you might want to set up a test system with the latest VoiceGuide release and matching newer HMP drivers and see how the newer HMP version system compares.

[lucasklos]

Hi Support team, 

Thanks for your reply. I've applied the suggested change and it started working. There was no change on voiceguide/hmp side, but there was new implementation in the PBX side. We've specified out-of-band + RFC2833, but it seems that they didn't apply that configuration (although they told us that they did  ).

We will analyze upgrading the software as a different project because our client want to have all the environment with the same version.